Bug Proofing Visual Basic: A Guide to Error Handling and Prevention
(Publisher: John Wiley & Sons, Inc.)
Author(s): Rod Stephens
ISBN: 0471323519
Publication Date: 11/01/98

Analyzing Results

After you have run a profiled application but before you remove the profiler code, you can examine the results of the profile run. In VBCP, open the File menu and select the View Results command. The display you see and the things you can learn from the display depend on the type of profile data you collected.

Line Timing

Figure 15.2 shows the result display for a line timing test. The display shows the total time spent running each line of code. It also shows the number of times each line was executed, the average amount of time taken each time the lines were executed, and the percentage of the program’s time spent running each line.

For instance, line 5 in the AddCharacter subroutine is

   txt = txtDisplay.Text

This line was executed 197 times during the test. It took 0.08 seconds for all 197 executions, or roughly 0.0004 seconds each time the line was executed. That was approximately 1.73 percent of the program’s total time.

Figure 15.2  Line timing statistics.

Notice that lines 8 and 10 of the AddCharacter routine have hit counts of 0 each. That shows these lines were not executed during the test. This could indicate a bug in the program if those lines should have been executed. In this case, the code executed a white box test that checked only a small part of the program. A more complete coverage test would be expanded to exercise lines 8 and 10.

By clicking on a column heading, you can make VBCP sort the results using that column. Figure 15.3 shows the same data in Figure 15.2 sorted by total time. You can use this display to quickly identify code that you should consider optimizing.

As you examine the statistics, keep user interactions in mind. In Figure 15.3, the line that took the most time was the statement

   MsgBox “No errors found.”

This single line took more than 3 seconds and accounted for almost 72 percent of the program’s total time. The reason this statement was so slow is that it had to wait for the user to click the message box’s Ok button. The call to MsgBox is quick, but the user is relatively slow. Because the profiler gives this line credit for so much of the program’s time, the other more interesting times seem small. The line that uses the second most time is given credit for only 14 percent of the total time. If you subtract out the time spent waiting for the user to close the message box, however, this line accounts for more than half of the program’s time.

You can also use this display to look for lines of code that are never used. Click on the Hits column heading to sort the results by number of hits. The lines that were never executed are listed at the top with hit counts of 0. You should examine each of these lines and determine which of three cases applies. First, if the line should have been executed but was not, fix the bug in the code. Second, if the tests were not thorough enough to exercise the code, expand the tests. Third, if the code is unnecessary, remove it.

Figure 15.3  Line timing statistics sorted by total time.

Figure 15.4  Function timing statistics sorted by total time.

Function Timing

Figure 15.4 shows the display for a function timing test sorted by total time. This display shows the total time spent in each routine. It also shows the number of times each routine ran, the average time used by the routine calls, and the percentage of the program’s total time due to each routine.

In this example, it might seem as if the TestWhiteBox subroutine is a good candidate for optimization. Actually, TestWhiteBox includes a call to MsgBox, so its speed is determined by how quickly the user dismisses the message box. This is also a test routine, so spending a lot of effort optimizing it probably makes little sense.

Line Hit Counting

Figure 15.5 shows the results of a line hit count test sorted by hits. You can use this display to see which lines of code are executed the most. If you scroll to the top of the display, you can see the lines that are never executed. The information presented here is also included in the line timing test shown in Figure 15.2. Collecting only the hit count information may be faster.

These statistics do not tell you whether an allocated variable is ever used. They also do not distinguish between the test and action parts in a single-line If statement. If the program reaches the If statement, the profiler counts the line as hit, whether the If statement’s test is True or False. Conversely, in a multiline If statement, the profiler does not count hits on lines that are not executed because the If statement’s condition is False.

In the following code, the hit count for the first DoSomething statement is 1 even though DoSomething is never called. The hit count for the DoSomethingElse statement is 0 because the multiline If statement surrounding it prevented it from executing.

Figure 15.5  Line hit count statistics sorted by hits.

   If False Then DoSomething    ‘ Hit count = 1.

   If False Then                ‘ Hit count = 1.
       DoSomethingElse          ‘ Hit count = 0.
End If

If you want really precise hit counts for the lines in your program, use multiline If statements.

Function Hit Counting

Figure 15.6 shows the results of a function hit count test sorted by hits. This shows the routines that ran the most. The function timing statistics shown in Figure 15.4 also include function hit information, although they do not show the percentage of hits due to each routine.